sync: time each peer's reconcile separately - #69
Merged
Conversation
The per-phase counters from #68 say the peer step is 90.8 percent of a sync pass on Silber, and that it is CPU rather than blocking. They cannot say whether both peers cost the same. That distinction decides the fix. In the window I measured, droppy was relay-routed and hetz was direct, in the same pass. If one of those dominates, the answer is about the path. If they cost the same, the answer is about the manifest, which is the same 31,000 entries either way. The aggregate counter hides exactly that. So each peer's reconcile is timed and logged to the validation log: peer, microseconds, and whether it failed. EMITTED BEFORE THE OUTCOME IS MATCHED, DELIBERATELY. Putting this inside the Ok arm would have hidden every failing peer, and a peer that times out or retries on a relay is precisely the expensive case being hunted. A diagnostic that only fires on success fails open and reports a healthy picture of an unhealthy one. A LOG LINE RATHER THAN A COUNTER, WHICH IS THE OPPOSITE OF #68. Peers are dynamic, so per-peer counters would put an unbounded set of keys on the control wire. This question is also a one-off: once we know whether the path matters, the line has served. The volume is proportionate at about 4.6 lines a minute against the roughly 15 that log already writes. `VALIDATION_LOG_TARGET` becomes `pub(crate)` instead of being retyped in a second place. Two copies of a literal drift apart. NO NEW TEST, AND I WILL NOT PRETEND OTHERWISE. This emits a diagnostic and changes no behaviour. The 237 lib and 12 bin tests are the control that it changed nothing. A test asserting a log line fires would need a subscriber-capture harness and would mirror the change rather than check it. Verified on macOS 15 arm64. Linux is CI's. Agent: Silber.fabric
myobie
added a commit
that referenced
this pull request
Aug 24, 2026
#69 shipped the per-peer reconcile timing at `debug!`. The daemon's default validation filter is `fabric=info`, set in `validation_log_filter`. So the line was dropped before it reached the log, and the instrument emitted NOTHING. I merged it, cut a release, rolled it to Silber, and then found three sync passes and zero `reconcile_peer` lines. Three passes is the positive control: the absence was the filter, not an idle daemon. Without that check I would have read an empty result as "reconcile is rare" and been wrong a fourth time in one evening. The fix is one word, `debug!` to `info!`. At about 4.6 lines a minute against the roughly 15 that log already writes, INFO is proportionate, and a diagnostic nobody can read is not cheaper than one they can. THE TEST IS THE POINT OF THIS COMMIT, AND I ARGUED AGAINST IT IN #69. I wrote there: "A test asserting that a log line fires would need a subscriber-capture harness and would mirror the change rather than check it." The first half was true. The second half was wrong, and it cost a merge, a release and a deploy. It is not a mirror. It pins the INTERACTION between two things written far apart and in different files: the level a diagnostic chooses, and the filter the daemon actually runs. Either can move without the other, and neither file mentions the other. `the_default_validation_filter_passes_info_and_drops_debug` builds the shipped default filter, installs it with a capturing writer, emits one INFO and one DEBUG event on the validation target, and asserts the first arrives and the second does not. I WATCHED IT FAIL IN THE EXACT SHAPE OF THE BUG. Changing the probe to `debug!` reproduces #69, and the test reports "an INFO diagnostic on the validation target must reach the log, got: " with an empty log. Verified on macOS 15 arm64: 238 lib tests, 12 bin tests, all pass. Agent: Silber.fabric
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
What this changes
The per-phase counters from #68 say the peer step is 90.8% of a sync pass on
Silber, and that it is CPU rather than blocking. They cannot say whether both
peers cost the same, and that distinction decides the fix.
In the window I measured,
droppywas relay-routed andhetzwas direct, in thesame pass. If one dominates, the answer is about the path. If they cost the same,
the answer is about the manifest — the same ~31,000 entries either way. The
aggregate counter hides exactly that.
Each peer's reconcile is now timed and logged: peer, microseconds, and whether it
failed.
Emitted before the outcome is matched, deliberately. Putting this inside the
Okarm would hide every failing peer, and a peer that times out or retries on arelay is precisely the expensive case being hunted. A diagnostic that only fires
on success fails open and reports a healthy picture of an unhealthy one.
A log line rather than a counter, which is the opposite of what #68 did. Peers
are dynamic, so per-peer counters would put an unbounded set of keys on the
control wire. The question is also a one-off: once we know whether the path
matters, the line has served its purpose. Volume is proportionate — about 4.6
lines/min against the ~15 that log already writes.
VALIDATION_LOG_TARGETbecomespub(crate)rather than being retyped in a secondplace, because two copies of a literal drift apart.
What was verified, and what was not
Platform: macOS 15 on arm64 (Silber). Linux is CI's.
cargo test --lib— 237 passed, 0 failed.cargo test --bins— 12 passed, 0 failed.No new test, and I am not going to dress that up. This emits a diagnostic and
changes no behaviour. The existing suites are the control that it changed nothing.
A test asserting that a log line fires would need a subscriber-capture harness and
would mirror the change rather than check it.
Not verified: the answer it exists to produce. I have not yet deployed it and
read the split — that is the next step, on Silber only.
Context
Issue #52 now carries the corrected framing and the measurement: cause 3 is full
manifest exchange per peer per pass, not "full decode per pass", and live cost is
manifest size multiplied by mutation rate.